1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
115
116
117
118
119
120
121
122
123
124
125
126
127
128
129
130
131
132
133
134
135
136
137
138
139
140
141
142
143
144
145
146
147
148
149
150
151
152
153
154
155
156
157
158
159
|
.. This work is licensed under a Creative Commons Attribution 4.0 International License.
.. http://creativecommons.org/licenses/by/4.0
.. _troubleshooting:
Troubleshooting
===============
**NOTE**
According to **ONAP** logging policy, **PM Mapper** logs contain all required markers as well as service and client specific Mapped Diagnostic Context (later referred as MDC)
Default console log pattern:
::
| %date{"yyyy-MM-dd'T'HH:mm:ss.SSSXXX", UTC}\t| %thread\t| %highlight(%-5level)\t| %msg\t| %marker\t| %rootException\t| %mdc\t| %thread
A sample, fully qualified message implementing this pattern:
::
| 2018-12-18T13:12:44.369Z | p.dcae | DEBUG | Client connection request received | ENTRY | | RequestID=d7762b18-854c-4b8c-84aa-95762c6f8e62, InstanceID=9b9799ca-33a5-4f61-ba33-5c7bf7e72d07, InvocationID=b13d34ba-e1cd-4816-acda-706415308107, PartnerName=C=PL, ST=DL, L=Wroclaw, O=Nokia, OU=MANO, CN=dcaegen2-hvves-client, StatusCode=INPROGRESS, ClientIPAddress=192.168.0.9, ServerFQDN=a4ca8f96c7e5 | reactor-tcp-nio-2
For simplicity, all log messages in this section are shortened to contain only:
* logger name
* log level
* message
Error and warning logs contain also:
* exception message
* stack trace
**Do not rely on exact log messages or their presence, as they are often subject to change.**
Configuration errors
--------------------
**Config binding service not responding**
::
2019-02-19T17:25:17.499Z main INFO org.onap.dcaegen2.services.pmmapper.config.ConfigHandler Fetching pm-mapper configuration from Configbinding Service ENTRY
2019-02-19T17:25:17.502Z main INFO org.onap.dcaegen2.services.pmmapper.utils.RequestSender ee5ff670-accd-4c30-8689-0a1d12491b51 INVOKE [ SYNCHRONOUS ]
2019-02-19T17:25:17.509Z main INFO org.onap.dcaegen2.services.pmmapper.utils.RequestSender Sending:\n{X-ONAP-PartnerName=[pm-mapper], X-ONAP-InvocationID=[ee5ff670-accd-4c30-8689-0a1d12491b51], X-ONAP-RequestID=[2778e346-590a-4ade-8f45-358d1adf048b]}
2019-02-19T17:25:18.515Z main INFO org.onap.dcaegen2.services.pmmapper.utils.RequestSender Sending:\n{X-ONAP-PartnerName=[pm-mapper], X-ONAP-InvocationID=[ee5ff670-accd-4c30-8689-0a1d12491b51], X-ONAP-RequestID=[2778e346-590a-4ade-8f45-358d1adf048b]}
2019-02-19T17:25:19.516Z main INFO org.onap.dcaegen2.services.pmmapper.utils.RequestSender Sending:\n{X-ONAP-PartnerName=[pm-mapper], X-ONAP-InvocationID=[ee5ff670-accd-4c30-8689-0a1d12491b51], X-ONAP-RequestID=[2778e346-590a-4ade-8f45-358d1adf048b]}
2019-02-19T17:25:20.518Z main INFO org.onap.dcaegen2.services.pmmapper.utils.RequestSender Sending:\n{X-ONAP-PartnerName=[pm-mapper], X-ONAP-InvocationID=[ee5ff670-accd-4c30-8689-0a1d12491b51], X-ONAP-RequestID=[2778e346-590a-4ade-8f45-358d1adf048b]}
2019-02-19T17:25:21.519Z main INFO org.onap.dcaegen2.services.pmmapper.utils.RequestSender Sending:\n{X-ONAP-PartnerName=[pm-mapper], X-ONAP-InvocationID=[ee5ff670-accd-4c30-8689-0a1d12491b51], X-ONAP-RequestID=[2778e346-590a-4ade-8f45-358d1adf048b]}
2019-02-19T17:25:21.520Z main INFO org.onap.dcaegen2.services.pmmapper.config.ConfigHandler Received pm-mapper configuration from ConfigBinding Service:\n EXIT
Exception in thread "main" org.onap.dcaegen2.services.pmmapper.exceptions.CBSServerError: Error connecting to Configbinding Service:
at org.onap.dcaegen2.services.pmmapper.config.ConfigHandler.getMapperConfig(ConfigHandler.java:78)
at org.onap.dcaegen2.services.pmmapper.App.main(App.java:58)
caused by: java.net.ConnectException: Connection refused (Connection refused)
at sun.reflect.NativeConstructorAccessorImpl.newInstance0(Native Method)
at sun.reflect.NativeConstructorAccessorImpl.newInstance(NativeConstructorAccessorImpl.java:62)
at sun.reflect.DelegatingConstructorAccessorImpl.newInstance(DelegatingConstructorAccessorImpl.java:45)
at java.lang.reflect.Constructor.newInstance(Constructor.java:423)
at sun.net.www.protocol.http.HttpURLConnection$10.run(HttpURLConnection.java:1944)
at sun.net.www.protocol.http.HttpURLConnection$10.run(HttpURLConnection.java:1939)
at java.security.AccessController.doPrivileged(Native Method)
at sun.net.www.protocol.http.HttpURLConnection.getChainedException(HttpURLConnection.java:1938)
at sun.net.www.protocol.http.HttpURLConnection.getInputStream0(HttpURLConnection.java:1508)
at sun.net.www.protocol.http.HttpURLConnection.getInputStream(HttpURLConnection.java:1492)
at java.net.HttpURLConnection.getResponseCode(HttpURLConnection.java:480)
at java.net.HttpURLConnection.getResponseMessage(HttpURLConnection.java:546)
at org.onap.dcaegen2.services.pmmapper.utils.RequestSender.send(RequestSender.java:80)
at org.onap.dcaegen2.services.pmmapper.config.ConfigHandler.getMapperConfig(ConfigHandler.java:76)
... 1 more
Caused by: java.net.ConnectException: Connection refused (Connection refused)
at java.net.PlainSocketImpl.socketConnect(Native Method)
at java.net.AbstractPlainSocketImpl.doConnect(AbstractPlainSocketImpl.java:350)
at java.net.AbstractPlainSocketImpl.connectToAddress(AbstractPlainSocketImpl.java:206)
at java.net.AbstractPlainSocketImpl.connect(AbstractPlainSocketImpl.java:188)
at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:392)
at java.net.Socket.connect(Socket.java:589)
t java.net.Socket.connect(Socket.java:538)
at sun.net.NetworkClient.doConnect(NetworkClient.java:180)
at sun.net.www.http.HttpClient.openServer(HttpClient.java:463)
at sun.net.www.http.HttpClient.openServer(HttpClient.java:558)
at sun.net.www.http.HttpClient.<init>(HttpClient.java:242)
at sun.net.www.http.HttpClient.New(HttpClient.java:339)
at sun.net.www.http.HttpClient.New(HttpClient.java:357)
at sun.net.www.protocol.http.HttpURLConnection.getNewHttpClient(HttpURLConnection.java:1220)
at sun.net.www.protocol.http.HttpURLConnection.plainConnect0(HttpURLConnection.java:1156)
at sun.net.www.protocol.http.HttpURLConnection.plainConnect(HttpURLConnection.java:1050)
at sun.net.www.protocol.http.HttpURLConnection.connect(HttpURLConnection.java:984)
at sun.net.www.protocol.http.HttpURLConnection.getInputStream0(HttpURLConnection.java:1564)
at sun.net.www.protocol.http.HttpURLConnection.getInputStream(HttpURLConnection.java:1492)
at org.onap.dcaegen2.services.pmmapper.utils.RequestSender.send(RequestSender.java:66)
Make sure Config Binding Service is up and running and the **ip + port** combination is correct.
====
**Missing configuration on Consul**
::
2019-02-19T17:36:32.664Z main INFO org.onap.dcaegen2.services.pmmapper.config.ConfigHandler Fetching pm-mapper configuration from Configbinding Service ENTRY
2019-02-19T17:36:32.666Z main INFO org.onap.dcaegen2.services.pmmapper.utils.RequestSender 9fa1b84f-05ce-4e27-bba9-4ea477c1baa7 INVOKE [ SYNCHRONOUS ]
2019-02-19T17:36:32.671Z main INFO org.onap.dcaegen2.services.pmmapper.utils.RequestSender Sending:\n{X-ONAP-PartnerName=[pm-mapper], X-ONAP-InvocationID=[9fa1b84f-05ce-4e27-bba9-4ea477c1baa7], X-ONAP-RequestID=[6e861d17-3f4b-4a2e-9ea8-a31bb9dbb7e8]}
2019-02-19T17:36:32.696Z main INFO org.onap.dcaegen2.services.pmmapper.utils.RequestSender Received:\n{"pm-mapper-filter": "{ \"filters\":[]}", "3GPP.schema.file": "{\"3GPP_Schema\":\"./etc/3GPP_relaxed_schema.xsd\"}", "streams_subscribes": {"dmaap_subscriber": {"type": "data_router", "aaf_username": null, "aaf_password": null, "dmaap_infooooo": {"location": "csit-pmmapper", "delivery_url": "3gpppmmapper", "username": "username", "password": "password", "subscriber_id": "subsriber_id"}}}, "streams_publishes": {"pm_mapper_handle_out": {"type": "message_router", "aaf_password": null, "dmaap_info": {"topic_url": "https://message-router:3904/events/org.onap.dmaap.onapCSIT.pm_mapper", "client_role": "org.onap.dmaap.client.pub", "location": "csit-pmmapper", "client_id": null}, "aaf_username": null}}, "buscontroller_feed_subscription_endpoint": "http://dmaap-bc:8080/webapi/dr_subs", "services_calls": {}}
2019-02-19T17:36:32.696Z main INFO org.onap.dcaegen2.services.pmmapper.config.ConfigHandler Received pm-mapper configuration from ConfigBinding Service:\n{"pm-mapper-filter": "{ \"filters\":[]}", "3GPP.schema.file": "{\"3GPP_Schema\":\"./etc/3GPP_relaxed_schema.xsd\"}", "streams_subscribes": {"dmaap_subscriber": {"type": "data_router", "aaf_username": null, "aaf_password": null, "dmaap_infooooo": {"location": "csit-pmmapper", "delivery_url": "3gpppmmapper", "username": "username", "password": "password", "subscriber_id": "subsriber_id"}}}, "streams_publishes": {"pm_mapper_handle_out": {"type": "message_router", "aaf_password": null, "dmaap_info": {"topic_url": "https://message-router:3904/events/org.onap.dmaap.onapCSIT.pm_mapper", "client_role": "org.onap.dmaap.client.pub", "location": "csit-pmmapper", "client_id": null}, "aaf_username": null}}, "buscontroller_feed_subscription_endpoint": "http://dmaap-bc:8080/webapi/dr_subs", "services_calls": {}} EXIT
Exception in thread "main" org.onap.dcaegen2.services.pmmapper.exceptions.MapperConfigException: Error parsing mapper configuration:
{}{"pm-mapper-filter": "{ \"filters\":[]}", "3GPP.schema.file": "{\"3GPP_Schema\":\"./etc/3GPP_relaxed_schema.xsd\"}", "streams_subscribes": {"dmaap_subscriber": {"type": "data_router", "aaf_username": null, "aaf_password": null, "dmaap_infooooo": {"location": "csit-pmmapper", "delivery_url": "3gpppmmapper", "username": "username", "password": "password", "subscriber_id": "subsriber_id"}}}, "streams_publishes": {"pm_mapper_handle_out": {"type": "message_router", "aaf_password": null, "dmaap_info": {"topic_url": "https://message-router:3904/events/org.onap.dmaap.onapCSIT.pm_mapper", "client_role": "org.onap.dmaap.client.pub", "location": "csit-pmmapper", "client_id": null}, "aaf_username": null}}, "buscontroller_feed_subscription_endpoint": "http://dmaap-bc:8080/webapi/dr_subs", "services_calls": {}}
at org.onap.dcaegen2.services.pmmapper.config.ConfigHandler.convertMapperConfigToObject(ConfigHandler.java:94)
at org.onap.dcaegen2.services.pmmapper.config.ConfigHandler.getMapperConfig(ConfigHandler.java:83)
at org.onap.dcaegen2.services.pmmapper.App.main(App.java:58)
Caused by: com.google.gson.JsonParseException: Failed to check fields.
at org.onap.dcaegen2.services.pmmapper.utils.RequiredFieldDeserializer.deserialize(RequiredFieldDeserializer.java:49)
at com.google.gson.internal.bind.TreeTypeAdapter.read(TreeTypeAdapter.java:69)
at com.google.gson.Gson.fromJson(Gson.java:927)
at com.google.gson.Gson.fromJson(Gson.java:892)
at com.google.gson.Gson.fromJson(Gson.java:841)
at com.google.gson.Gson.fromJson(Gson.java:813)
at org.onap.dcaegen2.services.pmmapper.config.ConfigHandler.convertMapperConfigToObject(ConfigHandler.java:92)
... 2 more
Caused by: com.google.gson.JsonParseException: Field: 'busControllerFeedId', is required but not found.
at org.onap.dcaegen2.services.pmmapper.utils.RequiredFieldDeserializer.deserialize(RequiredFieldDeserializer.java:46)
**PM Mapper** logs this information when connected to Consul, but cannot find a valid JSON configuration.
====
**Unable to Subscriber to Data Router Feed**
::
2019-02-11T16:44:37.012Z main DEBUG org.onap.dcaegen2.services.pmmapper.config.ConfigHandler Mapper configuration:\nMapperConfig(messageRouterTopicName=unauthenticated.PM_VES_OUTPUT, busControllerConfig=BusControllerConfig(dcaeLocation=dcaeLocation, deliveryURL=deliveryURL, feedId=2, lastMod=lastMod, username=username, password=password, dataRouterSubscribeEndpoint=null), streamsSubscribes=MapperConfig.StreamsSubscribes(dmaapSubscriber=MapperConfig.DmaapSubscriber(dmaapInfo=MapperConfig.DmaapInfo(location=location, username=username, password=password, deliveryUrl=delivery_url, subscriberId=subsriber_id))))
2019-02-11T16:44:37.013Z main INFO org.onap.dcaegen2.services.pmmapper.datarouter.DataRouterSubscriber Starting subscription to DataRouter ENTRY
2019-02-11T16:44:37.013Z main INFO org.onap.dcaegen2.services.pmmapper.datarouter.DataRouterSubscriber e04d9fb4-5bc3-405b-89ea-6b824de8f137 INVOKE [ SYNCHRONOUS ]
2019-02-11T16:44:37.061Z main INFO org.onap.dcaegen2.services.pmmapper.datarouter.DataRouterSubscriber Request to bus controller executed with Response Code: '404' and Response Event: 'Not Found'.
2019-02-11T16:44:39.062Z main INFO org.onap.dcaegen2.services.pmmapper.datarouter.DataRouterSubscriber d4982d98-574d-42e4-9922-640610ffa34d INVOKE [ SYNCHRONOUS ]
2019-02-11T16:44:39.071Z main INFO org.onap.dcaegen2.services.pmmapper.datarouter.DataRouterSubscriber Request to bus controller executed with Response Code: '404' and Response Event: 'Not Found'.
2019-02-11T16:44:43.079Z main INFO org.onap.dcaegen2.services.pmmapper.datarouter.DataRouterSubscriber 05c73228-d04c-47c2-b897-8e936de5c8fd INVOKE [ SYNCHRONOUS ]
2019-02-11T16:44:43.089Z main INFO org.onap.dcaegen2.services.pmmapper.datarouter.DataRouterSubscriber Request to bus controller executed with Response Code: '404' and Response Event: 'Not Found'.
2019-02-11T16:44:51.129Z main INFO org.onap.dcaegen2.services.pmmapper.datarouter.DataRouterSubscriber c898b5c7-a347-496a-af3b-aeac661d4f1b INVOKE [ SYNCHRONOUS ]
2019-02-11T16:44:51.138Z main INFO org.onap.dcaegen2.services.pmmapper.datarouter.DataRouterSubscriber Request to bus controller executed with Response Code: '404' and Response Event: 'Not Found'.
2019-02-11T16:45:07.220Z main INFO org.onap.dcaegen2.services.pmmapper.datarouter.DataRouterSubscriber b190fbc1-ab91-44da-b393-727810925374 INVOKE [ SYNCHRONOUS ]
2019-02-11T16:45:07.234Z main INFO org.onap.dcaegen2.services.pmmapper.datarouter.DataRouterSubscriber Request to bus controller executed with Response Code: '404' and Response Event: 'Not Found'.
2019-02-11T16:45:07.235Z main INFO org.onap.dcaegen2.services.pmmapper.datarouter.DataRouterSubscriber EXIT
Exception in thread "main" org.onap.dcaegen2.services.pmmapper.exceptions.TooManyTriesException: Failed to subscribe within appropriate amount of attempts
at org.onap.dcaegen2.services.pmmapper.datarouter.DataRouterSubscriber.subscribe(DataRouterSubscriber.java:152)
at org.onap.dcaegen2.services.pmmapper.datarouter.DataRouterSubscriber.subscribe(DataRouterSubscriber.java:150)
at org.onap.dcaegen2.services.pmmapper.datarouter.DataRouterSubscriber.subscribe(DataRouterSubscriber.java:150)
at org.onap.dcaegen2.services.pmmapper.datarouter.DataRouterSubscriber.subscribe(DataRouterSubscriber.java:150)
at org.onap.dcaegen2.services.pmmapper.datarouter.DataRouterSubscriber.subscribe(DataRouterSubscriber.java:150)
at org.onap.dcaegen2.services.pmmapper.datarouter.DataRouterSubscriber.start(DataRouterSubscriber.java:97)
at org.onap.dcaegen2.services.pmmapper.App.main(App.java:53)
This log is printed when pm mapper couldn't subscribe to the data router.
|
