[
https://issues.apache.org/jira/browse/CASSANDRA-5668?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=13690403#comment-13690403
]
Ryan McGuire commented on CASSANDRA-5668:
-----------------------------------------
The NullPointerException is gone, however, I see an unexpected change in the
trace after this commit.
Prior to the patch, I do this:
{code}
$ ccm create 5668
Current cluster is now: 5668
$ ccm populate -n 2:2
$ ccm start
$ ccm node1 cqlsh
Connected to 5668 at 127.0.0.1:9160.
[cqlsh 4.0.0 | Cassandra 2.0-SNAPSHOT | CQL spec 3.1.0 | Thrift protocol
19.37.0]
Use HELP for help.
cqlsh> CREATE KEYSPACE test WITH replication = {'class':
'NetworkTopologyStrategy', 'dc1':2, 'dc2':2};
cqlsh> CREATE TABLE test.test (id int PRIMARY KEY, value text);
cqlsh> tracing on;
Now tracing requests.
cqlsh> INSERT INTO test.test (id, value) VALUES ( 5, 'asdf');
Tracing session: 5d3bdaa0-da87-11e2-9eaa-35db2404c433
activity | timestamp
| source | source_elapsed
----------------------------------------------------------------+--------------+-----------+----------------
execute_cql3_query | 11:29:29,423
| 127.0.0.1 | 0
Parsing INSERT INTO test.test (id, value) VALUES ( 5, 'asdf'); | 11:29:29,424
| 127.0.0.1 | 1082
Peparing statement | 11:29:29,425
| 127.0.0.1 | 2241
Determining replicas for mutation | 11:29:29,425
| 127.0.0.1 | 2617
Sending message to /127.0.0.2 | 11:29:29,432
| 127.0.0.1 | 9321
Acquiring switchLock read lock | 11:29:29,433
| 127.0.0.1 | 10376
Appending to commitlog | 11:29:29,433
| 127.0.0.1 | 10424
Adding to test memtable | 11:29:29,433
| 127.0.0.1 | 10544
Sending message to /127.0.0.3 | 11:29:29,435
| 127.0.0.1 | 12658
Message received from /127.0.0.1 | 11:29:29,436
| 127.0.0.2 | 102
Message received from /127.0.0.1 | 11:29:29,438
| 127.0.0.3 | 103
Enqueuing forwarded write to /127.0.0.4 | 11:29:29,441
| 127.0.0.3 | 3596
Acquiring switchLock read lock | 11:29:29,441
| 127.0.0.3 | 3686
Appending to commitlog | 11:29:29,441
| 127.0.0.3 | 3704
Acquiring switchLock read lock | 11:29:29,442
| 127.0.0.2 | 5768
Adding to test memtable | 11:29:29,442
| 127.0.0.3 | 3759
Appending to commitlog | 11:29:29,442
| 127.0.0.2 | 5821
Sending message to /127.0.0.4 | 11:29:29,442
| 127.0.0.3 | 3834
Adding to test memtable | 11:29:29,442
| 127.0.0.2 | 5896
Enqueuing response to /127.0.0.1 | 11:29:29,442
| 127.0.0.3 | 4307
Enqueuing response to /127.0.0.1 | 11:29:29,443
| 127.0.0.2 | 6602
Message received from /127.0.0.3 | 11:29:29,444
| 127.0.0.4 | 92
Sending message to /127.0.0.1 | 11:29:29,444
| 127.0.0.2 | 8037
Message received from /127.0.0.2 | 11:29:29,445
| 127.0.0.1 | 36
Processing response from /127.0.0.2 | 11:29:29,445
| 127.0.0.1 | 147
Acquiring switchLock read lock | 11:29:29,452
| 127.0.0.4 | 8791
Appending to commitlog | 11:29:29,452
| 127.0.0.4 | 8835
Adding to test memtable | 11:29:29,452
| 127.0.0.4 | 8897
Enqueuing response to /127.0.0.1 | 11:29:29,453
| 127.0.0.4 | 9542
Sending message to /127.0.0.1 | 11:29:29,454
| 127.0.0.4 | 10021
Message received from /127.0.0.4 | 11:29:29,454
| 127.0.0.1 | 9660
Processing response from /127.0.0.4 | 11:29:29,455
| 127.0.0.1 | 9804
Request complete | 11:29:29,435
| 127.0.0.1 | 12668
{code}
That's a 2x2 multi-dc cluster with a RF of 2 in each dc. I write a single
INSERT and I see four nodes append to their commit log. All is well.
After the patch, I see this trace:
{code}
Tracing session: c3da4d00-da87-11e2-9a95-35db2404c433
activity | timestamp
| source | source_elapsed
----------------------------------------------------------------+--------------+-----------+----------------
execute_cql3_query | 11:32:21,587
| 127.0.0.1 | 0
Parsing INSERT INTO test.test (id, value) VALUES ( 5, 'asdf'); | 11:32:21,587
| 127.0.0.1 | 495
Peparing statement | 11:32:21,588
| 127.0.0.1 | 962
Determining replicas for mutation | 11:32:21,588
| 127.0.0.1 | 1108
Sending message to /127.0.0.2 | 11:32:21,590
| 127.0.0.1 | 3341
Sending message to /127.0.0.3 | 11:32:21,590
| 127.0.0.1 | 3920
Message received from /127.0.0.1 | 11:32:21,592
| 127.0.0.2 | 91
Message received from /127.0.0.1 | 11:32:21,593
| 127.0.0.3 | 93
Acquiring switchLock read lock | 11:32:21,593
| 127.0.0.2 | 1398
Appending to commitlog | 11:32:21,593
| 127.0.0.2 | 1447
Adding to test memtable | 11:32:21,593
| 127.0.0.2 | 1517
Enqueuing forwarded write to /127.0.0.4 | 11:32:21,594
| 127.0.0.3 | 1266
Enqueuing response to /127.0.0.1 | 11:32:21,594
| 127.0.0.2 | 2573
Acquiring switchLock read lock | 11:32:21,594
| 127.0.0.3 | 1343
Appending to commitlog | 11:32:21,594
| 127.0.0.3 | 1360
Adding to test memtable | 11:32:21,594
| 127.0.0.3 | 1412
Enqueuing response to /127.0.0.1 | 11:32:21,595
| 127.0.0.3 | 2060
Message received from /127.0.0.2 | 11:32:21,595
| 127.0.0.1 | null
Sending message to /127.0.0.1 | 11:32:21,595
| 127.0.0.2 | 2850
Sending message to /127.0.0.1 | 11:32:21,595
| 127.0.0.3 | 2442
Processing response from /127.0.0.2 | 11:32:21,595
| 127.0.0.1 | null
Sending message to /127.0.0.4 | 11:32:21,595
| 127.0.0.3 | 2442
Message received from /127.0.0.3 | 11:32:21,595
| 127.0.0.1 | null
Processing response from /127.0.0.3 | 11:32:21,595
| 127.0.0.1 | null
Message received from /127.0.0.3 | 11:32:21,597
| 127.0.0.4 | 95
Acquiring switchLock read lock | 11:32:21,598
| 127.0.0.4 | 1040
Appending to commitlog | 11:32:21,598
| 127.0.0.4 | 1087
Adding to test memtable | 11:32:21,598
| 127.0.0.4 | 1391
Enqueuing response to /127.0.0.1 | 11:32:21,599
| 127.0.0.4 | 1885
Message received from /127.0.0.4 | 11:32:21,600
| 127.0.0.1 | null
Sending message to /127.0.0.1 | 11:32:21,600
| 127.0.0.4 | 3290
Processing response from /127.0.0.4 | 11:32:21,600
| 127.0.0.1 | null
Request complete | 11:32:21,592
| 127.0.0.1 | 5564
{code}
127.0.0.1 (which also happens to be the coordinator) didn't write anything to
it's commit log (according to the trace at least). Reproducible on
cassandra-1.2 and trunk.
> NPE in net.OutputTcpConnection when tracing is enabled
> ------------------------------------------------------
>
> Key: CASSANDRA-5668
> URL: https://issues.apache.org/jira/browse/CASSANDRA-5668
> Project: Cassandra
> Issue Type: Bug
> Affects Versions: 1.2.6
> Reporter: Ryan McGuire
> Assignee: Jonathan Ellis
> Fix For: 1.2.6
>
> Attachments: 5668-assert-2.txt, 5668-assert.txt, 5668-followup.txt,
> 5668-logs.tar.gz, 5668_npe_ddl.cql, 5668_npe_insert.cql, 5668.txt, system.log
>
>
> I get multiple NullPointerException when trying to trace INSERT statements.
> To reproduce:
> {code}
> $ ccm create -v git:trunk
> $ ccm populate -n 3
> $ ccm start
> $ ccm node1 cqlsh < 5668_npe_ddl.cql
> $ ccm node1 cqlsh < 5668_npe_insert.cql
> {code}
> And see many exceptions like this in the logs of node1:
> {code}
> ERROR [WRITE-/127.0.0.3] 2013-06-19 14:54:35,885 OutboundTcpConnection.java
> (line 197) error writing to /127.0.0.3
> java.lang.NullPointerException
> at
> org.apache.cassandra.net.OutboundTcpConnection.writeConnected(OutboundTcpConnection.java:182)
> at
> org.apache.cassandra.net.OutboundTcpConnection.run(OutboundTcpConnection.java:144)
> {code}
> This is similar to CASSANDRA-5658 and is the reason that npe_ddl and
> npe_insert are separate files.
--
This message is automatically generated by JIRA.
If you think it was sent incorrectly, please contact your JIRA administrators
For more information on JIRA, see: http://www.atlassian.com/software/jira
